Aurora PostreSQLのログをCloudWatch Logsを経由せずに直接S3バケットにPUTしてみた
2025.01.12CloudWatch Logsを経由せずに直接S3バケットにログをPUTしたい
こんにちは、のんピ(@non____97)です。
皆さんはAurora PostgreSQLのログをCloudWatch Logsを経由せずに直接S3バケットにログをPUTしたいと思ったことはあります? 私はあります。
CloudWatch LogsにDBのログを流すとそれなりに料金がかかります。特にlog_statementであればall、mod、pgaudit.logであればall、read、writeにすると大量のログが流れがちです。
そのため、S3バケットにログを出力したいところでしょう。
S3バケットにログを出力する方法として、以下記事で紹介されているようにCloudWatch Logs → Data Firehose → S3という流れで連携させるものがあります。
ただし、以下記事で紹介されているように、CloudWatch Logsの料金が最もかかりやすい項目はログストレージの料金ではなく、ログ取り込み時に発生する料金です。
例えば月間のログ出力量が5TiBの場合、CloudWatch Logsのログ取り込みだけで5TiB × 1,024 x 0.76 USD = 3,891.20 USDかかります。なかなかの料金です。
S3の場合は取り込み時の料金はかかりません。(厳密にはPUTリクエストに料金がかかりますが、0.000005 USD/リクエストと微々たるものです)
つまり、コストを削減するためにはCloudWatch Logsを経由せずに直接S3バケットにPUTしたいです。
実際にやってみたので紹介します。
いきなりまとめ
- 定期的にDBインスタンス内のログファイルをS3バケットにPUTすることで、ログ出力に対する課金を抑えることができる
- Lambda関数のメモリサイズやエフェメラルストレージ、タイムアウト値はログファイルの数、ログファイルサイズで調整しよう
- ログファイルサイズは
log_rotation_sizeで調整しよう- ログローテーションのファイルサイズは1分では到達しない程度のもの かつ Lambda関数のメモリサイズやエフェメラルストレージで十分対応できるものを選択
- メモリサイズ以上のログファイルを操作しようとすると
MemoryErrorに
- 導入にあたっての注意点は以下3点
- ログの送信先
log_destinationがstderrの場合、Athenaでクエリできないログがある - ログファイルの欠損が起こりうる
- マネージドでリアルタイムなログ監視ができない
- ログの送信先
仕組みの紹介
全体構成
全体構成は以下のとおりです。
Step Functionsのステートマシンが動くたびにAurora DBクラスター内の全期間のログファイルや既にPUT済みのログファイルをPUTするのは非効率です。Lambda関数の実行時間も伸びてしまうでしょう。そのため、前処理としてAurora PostgreSQLのDBクラスターのログファイルのフィルタリングをしています。
「PUT済みのログファイルの判定は、S3の条件付き書き込みで代替できるのでは?」と思われる方もいるかもしれません。
確かに条件付き書き込みの機能に委ねても良いのですが、その前段でPUTするかどうか分からないログファイルをダウンロードする処理を全てのログファイルに行う必要があり、非効率です。そのため、手動で同じキーのオブジェクトがあるか判定させています。
ログファイルのフィルタリング後、各ログファイルごとにLambda関数を起動させ、ログファイルをS3バケットにPUTさせます。
また、赤枠で囲まれている箇所はAWS CDKでデプロイします。使用したコードは以下リポジトリに保存しています。
Aurora PostgreSQLのDBクラスターのログファイルのフィルタリング
こちらで行っている処理は以下のとおりです。
- 指定されたDBクラスター内のDBインスタンス名を取得する
- DBインスタンスごとに以下を並行処理
- 指定された期間内のログファイル一覧を取得
- 以下の条件のログファイルを除外
- ファイル名が正規表現パターン
postgresql\.log\.\d{4}-\d{2}-\d{2}-\d{4}$に当てはまらない - 最終更新時刻が最新のファイル
- ファイル名が正規表現パターン
- ログファイル名をパースし、オブジェクトキーを生成
- 指定されたS3バケットに生成したオブジェクトキーのオブジェクトがあるか確認する
- ない場合 : ログファイルのPUT対象とする
- ある場合 : ログファイルのPUT対象としない
- ログファイル情報一覧を返す
最終更新時刻が最新のファイルを除外としているのは最新のファイルは現在も書き込み途中である可能性があるためです。S3バケットにて上書きさせても良いですが、場合によってはログ取り込み時に上書きされると不都合があることもあります。
対応としてログファイルのローテーション間隔を短くすることが挙げられます。
ログファイルのローテーション間隔はデフォルトでは60分です。こちらを10分などより短い時間にすることで、ログファイルをPUTする間隔を短くすることが可能です。
ログファイル名をパースし、オブジェクトキーを生成ではDBクラスター名/DBインスタンス名/raw/YYYY/MM/DD/HH/ログファイル名としています。Aurora PostgreSQLのログファイル名のデフォルトフォーマットがpostgresql.log.%Y-%m-%d-%H%Mで、原則このフォーマットに沿ったログファイルに書き込まれるため、簡単に計算できます。(DBインスタンス起動時などの際にはerror/postgres.logにも書き込まれます)
なお、後述の処理で圧縮する場合は末尾に.gzを付与しています。これはAthenaが圧縮の有無および圧縮タイプをオブジェクトのメタデータではなく、拡張子で判断するためです。
CSV、TSV、および JSON のデータについては、Athena がファイル拡張子から圧縮タイプを判断します。ファイル拡張子がない場合、Athena はデータを非圧縮のプレーンテキストとして扱います。データが圧縮されている場合は、ファイル名に圧縮の拡張子 (gz など) が含まれていることを確認します。
仮に圧縮されたオブジェクトに対して.gzと拡張子を付与しない場合は、Athenaでクエリをしても何も表示されません。
個人的にはS3バケットのストレージコスト的にもAthenaのクエリ速度的にも圧縮はした方が良いと考えています。Athenaのパフォーマンスチューニングについては以下AWS公式ブログが参考になります。
こちらのLambda関数の実際のコードは以下のとおりです。
- Lambda関数のハンドラー
- ログファイルのフィルタリングする処理をまとめたクラス
RDSログのS3バケットへのPUT
こちらで行っている処理は以下のとおりです。
- 一時ファイルを作成する
- イベントで渡されたログファイルの情報を元にDBインスタンスのログファイルをダウンロードする処理を行う
- AWS Sigv4の署名付きリクエストを生成する
- ログファイルをダウンロードする
- イベントで渡されたログファイルの情報とダウンロードしたログファイルを元にS3バケットにPUTする処理を行う
- 圧縮が有効な場合は圧縮処理を実行する (圧縮レベル6)
- DBインスタンス名や最終書き込み日時などのメタデータを設定する
- S3バケットにPUTする
- 一時ファイルを削除する
RDSのログファイルのダウンロードを行うAPIDownloadCompleteLogFileに対応したAWS SDKはありません。そのため、直接APIリクエストを行う必要があります。組み立て方は以下AWS公式ドキュメントが参考になります。
類似のAPIであるDownloadDBLogFilePortionに対応したAWS SDKはあるのですが、こちらのAPIは最大10,000行までしかログメッセージを取得できません。Markerを指定して続きをダウンロードすることも可能ですが、手間です。詳細は以下記事をご覧ください。
こちらのLambda関数の実際のコードは以下のとおりです。
- Lambda関数のハンドラー
- DBインスタンスからログファイルをダウンロードする処理をまとめたクラス
- DBインスタンスのログファイルをS3バケットにPUTする処理をまとめたクラス
やってみた
検証環境
検証環境は以下のとおりです。
VPCやAurora DBクラスター、EC2インスタンス、S3バケットなど赤枠で囲まれた範囲外のリソースはデプロイ済みです。
> aws s3 ls aurora-postgresql-log
Aurora PostgreSQLのパラメーターの確認
Aurora PostgreSQLのパラメーターを事前にいくつか設定しておきました。
ログ量が多い状況を作り出したかったのでログ関連のものを変更しています。
各パラメーターの説明は以下のとおりです。
| パラメーター | 設定値 | デフォルト | 説明 |
|---|---|---|---|
| log_connections | 1 | ー | 成功した各接続をログに記録 |
| log_disconnections | 1 | ー | セッションの終了をログに記録 |
| log_duration | 1 | ー | 完了した各 SQL ステートメントの期間をログに記録 |
| log_hostname | 1 | 0 | 接続ログにホスト名を記録 |
| log_lock_waits | 1 | ー | 長期間にわたるロックの待機をログに記録 |
| log_min_duration_statement | 1 | ー | スロークエリと判定する最小実行時間 (msec) |
| log_min_messages | debug5 | ー | ログに記録するメッセージレベル |
| log_rotation_age | 10 | 60 | ログファイルのローテーション間隔 (minutes) |
| log_rotation_size | 200000 | 100000 | ログファイルのローテーションサイズ (KB) |
| pgaudit.log | all | ー | pgAuditによってログ記録されるステートメントの種類 |
| pgaudit.log_level | debug5 | ー | pgAuditのログに記録するメッセージレベル |
| pgaudit.log_parameter | 1 | ー | ステートメントとともに渡されたパラメータをpgAuditの監査ログ記録に含めるか |
| pgaudit.log_relation | 1 | ー | SELECT ステートメントまたは DML ステートメントで参照されるリレーション (TABLE、VIEW など) ごとにpgAuditの個別のログエントリを作成するかどうか |
| rds.log_retention_period | 10080 | 4320 | ログファイルの保持期間 (minutes) |
| shared_preload_libraries | pg_stat_statements,pgaudit | pg_stat_statements | DBインスタンスにプリロードする共有ライブラリ |
参考情報
- Aurora PostgreSQL でのログ記録のパラメータ - Amazon Aurora
- pgAudit 拡張機能のリファレンス - Amazon Relational Database Service
- RDS および Aurora PostgreSQL ログの操作: パート 1 | Amazon Web Services ブログ
- RDS for PostgreSQLのログ設定まとめ | DevelopersIO
pgAuditのセットアップ
pgAuditで監査ログを記録するためにいくつか設定が必要です。
psqlでDBインスタンスに接続します。
$ get_secrets_value=$(aws secretsmanager get-secret-value \
--secret-id rds!cluster-76576018-0911-40e8-8853-410abaeff6b3 \
--region us-east-1 \
| jq -r .SecretString)
$ export PGHOST=database-1-instance-1.cicjym7lykmq.us-east-1.rds.amazonaws.com
$ export PGPORT=5432
$ export PGDATABASE=postgres
$ export PGUSER=postgres
$ export PGPASSWORD=$(echo "${get_secrets_value}" | jq -r .password)
$ psql
psql (16.5, server 16.4)
SSL connection (protocol: TLSv1.3, cipher: TLS_AES_256_GCM_SHA384, compression: off)
Type "help" for help.
postgres=> \dt
Did not find any relations.
postgres=>
postgres=> \l
List of databases
Name | Owner | Encoding | Locale Provider | Collate | Ctype | ICU Locale | ICU Rules | Access privileges
-----------+----------+----------+-----------------+-------------+-------------+------------+-----------+-----------------------
postgres | postgres | UTF8 | libc | en_US.UTF-8 | en_US.UTF-8 | | |
rdsadmin | rdsadmin | UTF8 | libc | en_US.UTF-8 | en_US.UTF-8 | | | rdsadmin=CTc/rdsadmin
template0 | rdsadmin | UTF8 | libc | en_US.UTF-8 | en_US.UTF-8 | | | =c/rdsadmin +
| | | | | | | | rdsadmin=CTc/rdsadmin
template1 | postgres | UTF8 | libc | en_US.UTF-8 | en_US.UTF-8 | | | =c/postgres +
| | | | | | | | postgres=CTc/postgres
(4 rows)
pgAuditがプリロードされているか確認します。
postgres=> SHOW shared_preload_libraries;
shared_preload_libraries
--------------------------------------------------
rdsutils,pg_stat_statements,pgaudit,writeforward
(1 row)
pgAuditを有効化します。
postgres=> CREATE EXTENSION pgaudit;
CREATE EXTENSION
postgres=> SELECT * FROM pg_extension;
oid | extname | extowner | extnamespace | extrelocatable | extversion | extconfig | extcondition
-------+---------+----------+--------------+----------------+------------+-----------+--------------
14501 | plpgsql | 10 | 11 | f | 1.0 | |
49179 | pgaudit | 10 | 2200 | t | 16.0 | |
(2 rows)
サンプルデータ
サンプルデータを投入します。
$ curl https://ftp.postgresql.org/pub/projects/pgFoundry/dbsamples/iso-3166/iso-3166-1.0/iso-3166-1.0.tar.gz \
-s \
-o iso-3166-1.0.tar.gz
$ tar zxvf iso-3166-1.0.tar.gz
iso-3166/
iso-3166/iso-3166.sql
$ createdb -U postgres iso
$ psql -U postgres -f iso-3166/iso-3166.sql iso
BEGIN
SET
CREATE TABLE
COPY 242
CREATE TABLE
COPY 3995
COMMIT
ANALYZE
ANALYZE
ERRORログを出力するために既に存在するDBと同じ名前でDBを作ろうとしてみたり、同じデータを投入しようとしてみます。
$ createdb -U postgres iso
createdb: error: database creation failed: ERROR: database "iso" already exists
$ createdb -U postgres iso
createdb: error: database creation failed: ERROR: database "iso" already exists
$ createdb -U postgres iso
createdb: error: database creation failed: ERROR: database "iso" already exists
$ psql -U postgres -f iso-3166/iso-3166.sql iso
BEGIN
SET
psql:iso-3166/iso-3166.sql:9: ERROR: relation "country" already exists
psql:iso-3166/iso-3166.sql:11: ERROR: current transaction is aborted, commands ignored until end of transaction block
psql:iso-3166/iso-3166.sql:510: error: invalid command \N
psql:iso-3166/iso-3166.sql:511: error: invalid command \N
.
.
(中略)
.
.
psql:iso-3166/iso-3166.sql:4228: error: invalid command \N
psql:iso-3166/iso-3166.sql:4265: ERROR: syntax error at or near "Afghanistan"
LINE 1: Afghanistan|AF|4
^
また、1つのログファイルのサイズが大きくても問題なくS3にPUTできるか確認するために、サンプルデータの投入と削除を繰り返し行います。
$ dropdb -U postgres iso
$ while true; do
createdb -U postgres iso && \
psql -U postgres -f iso-3166/iso-3166.sql iso && \
dropdb -U postgres iso
done
BEGIN
SET
CREATE TABLE
COPY 242
CREATE TABLE
COPY 3995
COMMIT
ANALYZE
ANALYZE
BEGIN
SET
CREATE TABLE
COPY 242
CREATE TABLE
COPY 3995
COMMIT
ANALYZE
ANALYZE
.
.
.
(以下略)
現時点のログは以下のとおりです。
ログローテーションのファイルサイズは200MBで設定しているので、200MBほどでローテーションされていることが分かりますね。
なお、1分以内に複数回ローテーションが走ると、以下のように末尾に数字が付与されます。
記事投稿時点ではログファイル名がpostgresql\.log\.\d{4}-\d{2}-\d{2}-\d{4}$にマッチしていないものはPUTしないようになっているので注意してください。
このようにログファイルのフィルタリングをするときには都合が悪いので、ログローテーションのファイルサイズは1分では到達しない程度のもの かつ Lambda関数のメモリサイズやエフェメラルストレージで十分対応できるものを選択してください。
ログファイルをLambda関数内に一時的にダウンロードしたり、圧縮したりするのである程度の余裕は必要です。
ログファイルサイズのパラメーターlog_rotation_sizeはデフォルト100,000 KB = 100 MBで、50,000～1,000,000 KBの範囲で指定可能です。
参考までに一ヶ月にDBインスタンス5TiBのログを出力するの場合、1分間の平均ログ出力量は5 TiB * 1024 * 1024 / 31 days / 24 hour / 60 minutes = 117.45 MiBです。
不安であれば、200MiB〜500MiBぐらいのサイズでローテーションすると良いでしょう。
AWS CDKで関連リソースをデプロイ
AWS CDKで関連リソースをデプロイします。
プロパティの設定値は以下のとおりです。
- ターゲットのAurora DBクラスターの設定
- Lambda関数周りの設定
- ログの出力先の設定
- 定期実行の設定
実行結果の確認
現状、ログファイルをS3バケットへPUTする仕組みは10分間隔で、直近30分以内に出力されたログをS3バケットに圧縮してPUTするようにしています。
10分後、S3バケットのオブジェクト一覧を確認してみます。
> s3-tree aurora-postgresql-log
aurora-postgresql-log
└── database-1
├── databaes-1-instance-2
│ └── raw
│ └── 2025
│ └── 01
│ └── 11
│ └── 22
│ ├── postgresql.log.2025-01-11-2231.gz
│ ├── postgresql.log.2025-01-11-2240.gz
│ └── postgresql.log.2025-01-11-2248.gz
└── database-1-instance-1
└── raw
└── 2025
└── 01
└── 11
└── 22
├── postgresql.log.2025-01-11-2231.gz
├── postgresql.log.2025-01-11-2240.gz
├── postgresql.log.2025-01-11-2242.gz
├── postgresql.log.2025-01-11-2244.gz
├── postgresql.log.2025-01-11-2245.gz
├── postgresql.log.2025-01-11-2247.gz
└── postgresql.log.2025-01-11-2249.gz
14 directories, 10 files
Aurora DBクラスター内のDBインスタンスのログがPUTされていることが分かりますね。
また、オブジェクトのサイズを眺めてみると、約200MBだったファイルサイズが、3.0MBとなっていることから、おおよそオリジナルの15%ほどのサイズになっています。これはコストメリット大きいですね。
Step Functionsのステートマシンの実行結果を確認します。
特にエラーはありませんね。Iteration #9とあることからログを9個PUTしていたことが分かります。
X-Rayのトレース結果も眺めてみましょう。
ログファイルのフィルタリングが7秒ほどで、ログのPUTが最大17秒弱であることが分かります。Lambda関数とのメモリサイズと相談ですが、200MBのファイルであっても思ったよりも時間はかかりませんね。
ログファイルのフィルタリングするLambda関数のトレース結果は以下のとおりです。
同じオブジェクトキーがあるかの判定は早いと100msec、遅いと900msec弱かかるようです。ログファイルの数によってはLambda関数のタイムアウト値の調整が必要でしょう。
ログファイルをS3バケットへPUTするLambda関数のトレース結果は以下のとおりです
DBインスタンスからログファイルを取得するのに、12秒程度かかっていますね。
一方、ログファイルをS3にPUTする処理はおおよそ3.5秒程度です。その内実際にS3バケットへPUTするのにかかった時間は300msec未満です。そのため、ログファイルを圧縮するのに3秒程度かかっているのではと推測しています。
さらに10分経過後に実行された、ログファイルのフィルタリングするLambda関数のトレース結果は以下のとおりです。
いくつかのオブジェクトは存在しているので、404エラーの数が減っていますね。
オブジェクト一覧も以下のようになりました。
> s3-tree aurora-postgresql-log
aurora-postgresql-log
└── database-1
├── databaes-1-instance-2
│ └── raw
│ └── 2025
│ └── 01
│ └── 11
│ └── 22
│ ├── postgresql.log.2025-01-11-2231.gz
│ ├── postgresql.log.2025-01-11-2240.gz
│ ├── postgresql.log.2025-01-11-2248.gz
│ ├── postgresql.log.2025-01-11-2250.gz
│ └── postgresql.log.2025-01-11-2258.gz
└── database-1-instance-1
└── raw
└── 2025
└── 01
└── 11
└── 22
├── postgresql.log.2025-01-11-2231.gz
├── postgresql.log.2025-01-11-2240.gz
├── postgresql.log.2025-01-11-2242.gz
├── postgresql.log.2025-01-11-2244.gz
├── postgresql.log.2025-01-11-2245.gz
├── postgresql.log.2025-01-11-2247.gz
├── postgresql.log.2025-01-11-2249.gz
├── postgresql.log.2025-01-11-2250.gz
├── postgresql.log.2025-01-11-2251.gz
├── postgresql.log.2025-01-11-2253.gz
├── postgresql.log.2025-01-11-2255.gz
├── postgresql.log.2025-01-11-2256.gz
└── postgresql.log.2025-01-11-2258.gz
14 directories, 18 files
さらに放置すると以下のようになりました。意図したとおりのプレフィックスになっていますね。
> s3-tree aurora-postgresql-log
aurora-postgresql-log
└── database-1
├── databaes-1-instance-2
│ └── raw
│ └── 2025
│ └── 01
│ └── 11
│ ├── 22
│ │ ├── postgresql.log.2025-01-11-2231.gz
│ │ ├── postgresql.log.2025-01-11-2240.gz
│ │ ├── postgresql.log.2025-01-11-2248.gz
│ │ ├── postgresql.log.2025-01-11-2250.gz
│ │ └── postgresql.log.2025-01-11-2258.gz
│ └── 23
│ ├── postgresql.log.2025-01-11-2300.gz
│ └── postgresql.log.2025-01-11-2308.gz
└── database-1-instance-1
└── raw
└── 2025
└── 01
└── 11
├── 22
│ ├── postgresql.log.2025-01-11-2231.gz
│ ├── postgresql.log.2025-01-11-2240.gz
│ ├── postgresql.log.2025-01-11-2242.gz
│ ├── postgresql.log.2025-01-11-2244.gz
│ ├── postgresql.log.2025-01-11-2245.gz
│ ├── postgresql.log.2025-01-11-2247.gz
│ ├── postgresql.log.2025-01-11-2249.gz
│ ├── postgresql.log.2025-01-11-2250.gz
│ ├── postgresql.log.2025-01-11-2251.gz
│ ├── postgresql.log.2025-01-11-2253.gz
│ ├── postgresql.log.2025-01-11-2255.gz
│ ├── postgresql.log.2025-01-11-2256.gz
│ └── postgresql.log.2025-01-11-2258.gz
└── 23
├── postgresql.log.2025-01-11-2300.gz
├── postgresql.log.2025-01-11-2301.gz
├── postgresql.log.2025-01-11-2303.gz
├── postgresql.log.2025-01-11-2305.gz
├── postgresql.log.2025-01-11-2306.gz
└── postgresql.log.2025-01-11-2308.gz
16 directories, 26 files
最も負荷がかかる処理を行っているのはS3バケットへログをPUTするLambda関数です。
こちらのLambda関数のメモリ使用量をCloudWatch Logs Insightsで計測してみます。
filter @type = "REPORT"
| stats
min(record.metrics.maxMemoryUsedMB) as minMemory,
max(record.metrics.maxMemoryUsedMB) as maxMemory,
avg(record.metrics.maxMemoryUsedMB) as avgMemory,
pct(record.metrics.maxMemoryUsedMB, 60) as p60Memory,
pct(record.metrics.maxMemoryUsedMB, 70) as p70Memory,
pct(record.metrics.maxMemoryUsedMB, 80) as p80Memory,
pct(record.metrics.maxMemoryUsedMB, 90) as p90Memory
実行結果は以下のとおりです。
| minMemory | maxMemory | avgMemory | p60Memory | p70Memory | p80Memory | p90Memory |
|---|---|---|---|---|---|---|
| 96 | 504 | 404.5 | 494 | 495 | 497 | 501 |
Lambda関数に割り当てたメモリサイズは1,024MBです。ログファイルサイズが200MBで500MB程度使用するので、単純計算で400MB以上のファイルを扱うときはメモリサイズを調整した方が良いかもしれません。
参考までにLambda関数のメモリサイズを128MBにして、200MBのファイルを圧縮しようとすると以下のようにファイル読み込みの際にMemoryErrorとなります。
{
"level": "ERROR",
"location": "_compress_file:82",
"message": "Failed to compress file",
"timestamp": "2025-01-12 06:30:16,205+0000",
"service": "rds-log-file-uploader",
"cold_start": true,
"function_name": "AuroraPostgresqlLogArchiv-LambdaConstructRdsLogFil-iJZNuDkxaFnp",
"function_memory_size": "128",
"function_arn": "arn:aws:lambda:us-east-1:984900217833:function:AuroraPostgresqlLogArchiv-LambdaConstructRdsLogFil-iJZNuDkxaFnp",
"function_request_id": "5211b297-37db-4786-8403-7424f6bd2fbf",
"file_path": "/tmp/tmpeapi0u5o",
"error": "",
"exception": "Traceback (most recent call last):\n File \"/var/task/rds_log_file_uploader.py\", line 66, in _compress_file\n f_out.write(f_in.read())\n ~~~~~~~~~^^\nMemoryError",
"exception_name": "MemoryError",
"stack_trace": {
"type": "MemoryError",
"value": "",
"module": "builtins",
"frames": [
{
"file": "/var/task/rds_log_file_uploader.py",
"line": 66,
"function": "_compress_file",
"statement": "f_out.write(f_in.read())"
}
]
},
"xray_trace_id": "1-67836156-a61b1c863ad9c7e3ba6264ea"
}
Athenaでpostgresql.logに対してクエリをかけてみる
テーブルの作成
CloudWatch Logsにログを流す場合は、CloudWatch Logs Insightsでログに対してクエリをかけることができます。
では、S3バケットにログを流した場合はログ分析を諦めることになるか、というとそうではありません。
AthenaでS3バケットにPUTされたPostgreSQLのログにクエリをかけることも可能です。
以下のDDLでAthenaのテーブルを作成します。
CREATE EXTERNAL TABLE `postgresql_logs` (
`log_timestamp` timestamp,
`remote_host` string,
`username` string,
`database` string,
`process_id` int,
`log_level` string,
`log_type` string,
`message` string
)
PARTITIONED BY (
`datehour` string
)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
'input.regex' = '(\\d{4}-\\d{2}-\\d{2}\\s\\d{2}:\\d{2}:\\d{2})\\s[A-Z]+:(?::)?([^:]*)?(?::([^@]*))?@([^:\\[]*):\\[([0-9]+)\\]:([A-Z]+):\\s*(?:(AUDIT|duration):\\s*)?(.*)',
'serialization.format' = '1',
'timestamp.formats'='yyyy-MM-dd HH:mm:ss'
)
STORED AS TEXTFILE
LOCATION 's3://aurora-postgresql-log/database-1/database-1-instance-1/raw/'
TBLPROPERTIES (
'projection.enabled' = 'true',
'has_encrypted_data'='true',
'projection.datehour.type'='date',
'projection.datehour.interval'='1',
'projection.datehour.interval.unit'='HOURS',
'projection.datehour.range'='NOW-1MONTH,NOW',
'projection.datehour.format'='yyyy/MM/dd/HH',
'storage.location.template'='s3://aurora-postgresql-log/database-1/database-1-instance-1/raw/${datehour}'
);
aurora-postgresql-logはS3バケット名でdatabase-1はDBクラスター名、database-1-instance-1はDBインスタンス名です。流用する場合は適宜修正してください。
ログのプレフィックスであるlog_line_prefixは%t:%r:%u@%d:[%p]:であり、固定です。各値の説明は以下のとおりです。
| 値 | 説明 |
|---|---|
%t |
ログエントリの時刻 |
%r |
リモートホストのアドレス |
%u@%d |
ユーザー名 @ データベース名 |
[%p] |
プロセス ID |
こちらのログのパースはRegex SerDeによる正規表現で行っています。
正規表現のパターンの説明は以下のとおりです。
| パターン | 説明 | 例 | キャプチャ対象 |
|---|---|---|---|
(\\d{4}-\\d{2}-\\d{2}\\s\\d{2}:\\d{2}:\\d{2}) |
タイムスタンプ | 2025-01-10 01:45:37.000 | Yes |
\\s[A-Z]+: |
タイムゾーンUTC | UTC | No |
: |
区切り文字 | No | |
(?::)? |
区切り文字 リモートホストが記録されていない場合は連続して : が続く |
No | |
([^:]*)? |
リモートホスト ログによっては記録されていない |
ip-172-31-42-90.ec2.internal(32980) | Yes |
(?::([^@]*))? |
ユーザー名 ログによっては記録されていない |
postgres | Yes |
@ |
@ | No | |
([^:\\[]*) |
データベース名 ログによっては記録されていない |
iso | Yes |
: |
区切り文字 | No | |
\\[([0-9]+)\\] |
プロセスID | 1651 | Yes |
: |
区切り文字 | No | |
([A-Z]+) |
ログレベル | LOG | Yes |
: |
区切り文字 | No | |
\\s* |
任意の空白 | No | |
(?:(AUDIT|duration):\\s*)? |
ログタイプ (AUDITまたはduration) | AUDIT | Yes |
(.*) |
メッセージ本文 | SESSION,6,2134,READ,SELECT,TABLE,public.country,"SELECT 1 FROM ONLY ""public"".""country"" x WHERE ""two_letter"" OPERATOR(pg_catalog.=) $1 FOR KEY SHARE OF x",LR | Yes |
ログタイプのカラムを作成したのは監査ログ以外のログを抽出したり、スロークエリログのみを抽出したりをしやすくするためです。
ERRORログの抽出
まず、ERRORログの抽出を行います。
SELECT *
FROM
postgresql_logs
WHERE
datehour>='2025/01/11/22' AND
datehour<='2025/01/11/23' AND
log_level='ERROR'
LIMIT 20
実行結果は以下のとおりです。
# log_timestamp remote_host username database process_id log_level log_type message datehour
1 2025-01-11 22:39:40.000 ip-172-31-42-90.ec2.internal(57610) postgres postgres 14681 ERROR database "iso" already exists 2025/01/11/22
2 2025-01-11 22:39:41.000 ip-172-31-42-90.ec2.internal(57620) postgres postgres 14683 ERROR database "iso" already exists 2025/01/11/22
3 2025-01-11 22:39:42.000 ip-172-31-42-90.ec2.internal(57634) postgres postgres 14685 ERROR database "iso" already exists 2025/01/11/22
4 2025-01-11 22:39:46.000 ip-172-31-42-90.ec2.internal(57640) postgres iso 14691 ERROR relation "country" already exists 2025/01/11/22
5 2025-01-11 22:39:46.000 ip-172-31-42-90.ec2.internal(57640) postgres iso 14691 ERROR current transaction is aborted, commands ignored until end of transaction block 2025/01/11/22
6 2025-01-11 22:39:46.000 ip-172-31-42-90.ec2.internal(57640) postgres iso 14691 ERROR syntax error at or near "Afghanistan" at character 1 2025/01/11/22
7 2025-01-11 23:08:54.000 ip-172-31-42-90.ec2.internal(34244) postgres iso 20187 ERROR canceling statement due to user request 2025/01/11/23
8 2025-01-11 23:08:54.000 ip-172-31-42-90.ec2.internal(34268) postgres postgres 20190 ERROR database "iso" already exists 2025/01/11/23
9 2025-01-11 23:08:54.000 ip-172-31-42-90.ec2.internal(34280) postgres postgres 20191 ERROR database "iso" already exists 2025/01/11/23
10 2025-01-11 23:08:54.000 ip-172-31-42-90.ec2.internal(34294) postgres postgres 20192 ERROR database "iso" already exists 2025/01/11/23
11 2025-01-11 23:08:54.000 ip-172-31-42-90.ec2.internal(34304) postgres postgres 20193 ERROR database "iso" already exists 2025/01/11/23
12 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34312) postgres postgres 20194 ERROR database "iso" already exists 2025/01/11/23
13 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34314) postgres postgres 20195 ERROR database "iso" already exists 2025/01/11/23
14 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34326) postgres postgres 20196 ERROR database "iso" already exists 2025/01/11/23
15 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34342) postgres postgres 20197 ERROR database "iso" already exists 2025/01/11/23
16 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34354) postgres postgres 20198 ERROR database "iso" already exists 2025/01/11/23
17 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34362) postgres postgres 20200 ERROR database "iso" already exists 2025/01/11/23
18 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34366) postgres postgres 20201 ERROR database "iso" already exists 2025/01/11/23
19 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34376) postgres postgres 20202 ERROR database "iso" already exists 2025/01/11/23
20 2025-01-11 23:08:55.000 ip-172-31-42-90.ec2.internal(34380) postgres postgres 20203 ERROR database "iso" already exists 2025/01/11/23
log_type以外は全てのカラムに値が入っていますね。log_typeはオプションなので意図したとおりです。
また、スキャンデータ量は10MB程度で、実行時間も5秒ほどです。人力でログファイルを全てダウンロードして、grepするよりかは圧倒的に楽で早いですね。
FATALログ
続いてFATALログです。
SELECT *
FROM
postgresql_logs
WHERE
datehour>='2025/01/11/22' AND
datehour<='2025/01/11/23' AND
log_level='FATAL'
LIMIT 20
実行結果は以下のとおりです。
Auto Vacuumのログがほとんどですね。DB内部の処理であるため、remote_hostやusername、databaseはnullになっています。
また、複数のオブジェクトをチェックしたからか実行時間は13秒と長くなっています。
pgAuditのログの抽出
次にpgAuditのログです。
SELECT *
FROM
postgresql_logs
WHERE
datehour>='2025/01/11/22' AND
datehour<='2025/01/11/23' AND
log_level='LOG' AND
log_type='AUDIT'
LIMIT 20
実行結果は以下のとおりです。
正常に実行できていそうですね。
ただし、場合によっては以下のように1つのログで複数行出力されることがあります。
2025-01-11 22:38:37 UTC:ip-172-31-42-90.ec2.internal(36760):postgres@iso:[14617]:LOG: AUDIT: SESSION,3,1,DDL,CREATE TABLE,,,"CREATE TABLE country (
name TEXT NOT NULL,
two_letter TEXT PRIMARY KEY,
country_id integer NOT NULL
);",<none>
このような場合は改行以降のステートメントを表示することができません。
正確にパースしたい場合は、csv形式でログ出力するようにパラメーターグループのパラメーターを修正する必要があります。
Aurora PostgreSQL は、csvlog フォーマットでログを生成することもできます。csvlog は、ログデータをカンマ区切り値 (CSV) データとして分析する場合に便利です。例えば、log_fdw 拡張機能を使用して外部テーブルとしてログを使用するとします。stderr ログファイルについて作成された外部テーブルには、ログイベントデータを含む 1 つの列が含まれます。log_destination パラメータに csvlog を追加すると、外部テーブルの複数の列の区切りを含む CSV 形式のログファイルが取得できます。ログをより簡単に分類して分析できるようになりました。
このパラメータに csvlog を指定する場合、stderr ファイル と csvlog ファイルの両方が生成されることに注意してください。ログのストレージと回転率に影響する rds.log_retention_period とその他の設定を考慮し、ログによって消費されるストレージに注意してください。stderr と csvlog を使用すると、ログで消費されるストレージが 2 倍以上になります。
スロークエリのログの抽出
次にスロークエリログです。
SELECT *
FROM
postgresql_logs
WHERE
datehour>='2025/01/11/22' AND
datehour<='2025/01/11/23' AND
log_level='LOG' AND
log_type='duration'
LIMIT 20
実行結果は以下のとおりです。
スロークエリも場合によっては以下のように複数行に渡ってログ出力されます。注意しましょう。
2025-01-11 22:38:37 UTC:ip-172-31-42-90.ec2.internal(36760):postgres@iso:[14617]:LOG: duration: 31.617 ms statement: CREATE TABLE country (
name TEXT NOT NULL,
two_letter TEXT PRIMARY KEY,
country_id integer NOT NULL
);
pgAuditでもスロークエリでもないLOGのログ抽出
最後に、pgAuditでもスロークエリでもないログレベルLOGのログです。
SELECT *
FROM
postgresql_logs
WHERE
datehour>='2025/01/11/22' AND
datehour<='2025/01/11/23' AND
log_level='LOG' AND
log_type is null
ORDER BY log_timestamp
LIMIT 20
実行結果は以下のとおりです。
起動時のDBインスタンス起動時のログが表示されていますね。
コスト試算
月間のログ出力量が5TiBの場合、CloudWatch Logsのログ取り込みだけで5TiB × 1,024 x 0.76 USD = 3,891.20 USDでした。
こちらの仕組みのコスト試算をしてみます。
S3のストレージコストを除けば、ほぼLambda関数のコストになります。
各Lambda関数の毎月のコストは以下のとおりです。
- Aurora PostgreSQLのDBクラスターのログファイルのフィルタリング : 0.07 USD / month
| 項目 | 値 | |
|---|---|---|
| アーキテクチャ | Arm | |
| リクエスト数 | 6 / hour | 10分に一回起動 |
| 各リクエストの実行時間 | 10000 msec | 10秒想定 |
| メモリサイズ | 128 MB | デフォルト |
| エフェメラルストレージサイズ | 512 MB | デフォルト |
- RDSログのS3バケットへのPUT : 23.40 USD / month
| 項目 | 値 | |
|---|---|---|
| アーキテクチャ | Arm | |
| リクエスト数 | 60 / hour | 1分に1ログファイル出力される想定 |
| 各リクエストの実行時間 | 40000 msec | 40秒想定 |
| メモリサイズ | 1,024 MB | デフォルト |
| エフェメラルストレージサイズ | 1,024 MB | デフォルト |
合わせて25 USDにもなりません。Lambda関数が出力するCloudWatch LogsやStep Functionsの状態遷移にかかる料金含めても30 USDにもならないでしょう。
ログの出力量が多すぎてコストインパクトが大きい場合に
Aurora PostreSQLのログをCloudWatch Logsを介さずに直接S3バケットにPUTしてみました。
ログの出力量が多すぎてコストインパクトが大きい場合にはこちらのような仕組みを検討してみましょう。
導入にあたっての注意点は以下3点です。
- ログの送信先
log_destinationがstderrの場合、Athenaでクエリできないログがある - ログファイルの欠損が起こりうる
- マネージドでリアルタイムなログ監視ができない
「1. ログの送信先log_destinationがstderrの場合、Athenaでクエリできないログがある
」は前述したとおり、複数行に渡って出力されるログに対してAthenaでクエリできない場合があります。その場合はlog_destinationがcsvlogに変更することを検討しましょう。
最も注意が必要なのは「2. ログファイルの欠損が起こりうる」です。
この仕組みはDBインスタンス内のログファイルを定期的に取得しています。そのため、元となるログファイルが削除された場合やアクセスできない場合はログをS3バケットにPUTすることはできません。
例えば、リアルタイムで転送している訳ではないので、DBインスタンスを停止や削除する直前のログを転送することはできません。また、以下記事で紹介しているとおり、t系のインスタンスクラスタイプを使っている場合は停止する度にログファイルが削除されます。
停止や削除、インスタンスクラスタイプの変更前は、接続元のアプリケーションからのアクセスを停止させたり、Aurora DBクラスターのセキュリティグループのインバウンドルールを全て削除して、ログ流量を事前に減らすといったアプローチが必要になる場合もあるでしょう。
ただ、その場合でも停止や削除、インスタンスクラスタイプの変更前のDBのログは流れ続けます。これを切り捨てることができるかは十分に検討が必要です。場合によっては監査部門からNGが出ることもあるでしょう。
ログ欠損のリスクを極小化させたい場合はCloudWatch Logsに出力させることになります。
「3. マネージドでリアルタイムなログ監視ができない」はCloudWatch Logsに転送させないことによるデメリットです。CloudWatch Logsにログを流す場合はサブスクリプションフィルターやメトリクスフィルターで特定の文字列を含むログが出力された場合はLambda関数を実行したり、CloudWatchのカスタムメトリクスをPUTしたりすることが可能です。
この仕組みを単体ではそういったリアルタイムな検知ができません。実装する場合はログファイルをPUTする前にログファイルをpandas等で分析するなどの一手間が必要になると考えます。
Data FirehoseやS3バケットに直接ログを流せられるようになるアップデートが来れば万事解決です。早く来ることを待ち望んでいます。
この記事が誰かの助けになれば幸いです。
以上、クラウド事業本部 コンサルティング部の のんピ(@non____97)でした!
![[レポート] 目的に応じたマネージドデータベースの使い方が学べるワークショップ「Build a web-scale application with purpose-built databases & analytics [REPEAT]」 #DAT403-R1 #AWSreInvent](https://images.ctfassets.net/ct0aopd36mqt/3IQLlbdUkRvu7Q2LupRW2o/edff8982184ea7cc2d5efa2ddd2915f5/reinvent-2024-sessionreport-jp.jpg)
